RedshiftでELBのアクセスログ（9千万件）を解析してみた

suzuki.ryo

2016.04.06

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

はじめに

AWSチームのすずきです。

AWSが提供するDWHのAmazon Redshiftを利用して、S3上に保管されたELBのアクセスログ（15万ファイル、30GB、9千万レコード）を解析する機会がありましたので、その内容について簡単に紹介させていただきます。

参考資料

今回の作業にあたって、以下の記事を参考とさせて頂きました。

環境情報

Amazon Redshiftは、東京リージョン起動済みのクラスタを利用しました。（ds1.large×1台）

一時テーブル作成

CREATE TABLE IF NOT EXISTS tmp_elb_access_log
(
request_time VARCHAR (32)
,elb VARCHAR (64)
,client_port VARCHAR (32)
,backend_port VARCHAR (32)
,request_processing_time FLOAT
,backend_processing_time FLOAT
,response_processing_time FLOAT
,elb_status_code VARCHAR (4)
,backend_status_code VARCHAR (4)
,received_bytes BIGINT
,sent_bytes BIGINT
,request VARCHAR (2048)
,user_agent VARCHAR (1024)
,ssl_cipher VARCHAR (64)
,ssl_protocol VARCHAR (64)
)
;

インポート

COPY tmp_elb_access_log
FROM
's3://elb-logs-xxxxxxxx/dev/AWSLogs/nnnnnnnnnnnn/elasticloadbalancing/ap-northeast-1/'
CREDENTIALS 'aws_iam_role=arn:aws:iam::nnnnnnnnnnnn:role/redshift-role-mmmmmmmmm'
REGION 'ap-northeast-1'
delimiter ' '
ACCEPTINVCHARS REMOVEQUOTES FILLRECORD
MAXERROR AS 100000

設定内容

S3(elb-logs-xxxxxxxx)はELBのアクセスログ出力先を指定しました
CREDENTIALSは事前に用意したロール、またはアクセスキーを利用しました
参考: RedshiftのIAM Roles利用が可能となりました。
S3,Redshiftはともに東京リージョンですが、リージョンを明示しました。（REGION 'ap-northeast-1' ）
カラム区切りはスペースとしました（delimiter ' ' ）
UTF8無効文字は「？」としてエラー回避しました（ACCEPTINVCHARS）
元データの引用符撤去しました（REMOVEQUOTES）
カラム欠落レコード許容しました（FILLRECORD）
エラーレコードは設定可能な最大数まで許容するとしました（AXERROR AS 100000）

確認

SELECT COUNT(1) FROM tmp_elb_access_log

解析テーブル作成

CREATE TABLE IF NOT EXISTS elb_access_log
(
request_time TIMESTAMP
,request_date_jst TIMESTAMP
,elb VARCHAR (64)
,client_ip VARCHAR (64)
,client_port INTEGER
,backend_ip VARCHAR (64)
,backend_port INTEGER
,request_processing_time FLOAT
,backend_processing_time FLOAT
,response_processing_time FLOAT
,elb_status_code VARCHAR (4)
,backend_status_code VARCHAR (4)
,received_bytes BIGINT
,sent_bytes BIGINT
,request_method VARCHAR (8)
,request_uri VARCHAR (256)
,request_http_version VARCHAR (16)
,request_dir_1 VARCHAR (32)
,user_agent VARCHAR (256)
,ssl_cipher VARCHAR (64)
,ssl_protocol VARCHAR (64)
)
DISTKEY (request_time)
SORTKEY (request_date_jst, request_uri, request_dir_1, user_agent)

データ投入

INSERT INTO elb_access_log
(
SELECT
(request_time::TIMESTAMP) as request_time,
CONVERT_TIMEZONE('JST',request_time::date) as request_date_jst,
(elb::VARCHAR(64)) AS elb,
(NULLIF(SPLIT_PART(client_port, ':', 1), '-')::VARCHAR(64)) AS client_ip,
(NULLIF(SPLIT_PART(client_port, ':', 2), '-')::INTEGER) AS client_port,
case backend_port when '-' then NULL else SPLIT_PART(backend_port, ':', 1) end AS backend_ip,
case backend_port when '-' then NULL else SPLIT_PART(backend_port, ':', 2)::INTEGER end AS backend_port,
request_processing_time AS request_processing_time,
backend_processing_time AS backend_processing_time,
response_processing_time AS response_processing_time,
(NULLIF(elb_status_code, '-')::VARCHAR(4)) AS elb_status_code,
(NULLIF(backend_status_code, '-')::VARCHAR(4)) AS backend_status_code,
received_bytes,
sent_bytes,
(NULLIF(SPLIT_PART(request, ' ', 1), '-')::VARCHAR(8)) AS request_method,
(NULLIF(SPLIT_PART(request, ' ', 2), '-')::VARCHAR(256)) AS request_uri ,
(NULLIF(SPLIT_PART(request, ' ', 3), '-')::VARCHAR(16)) AS request_http_version,
(NULLIF(SPLIT_PART(request, '/', 4), '-')::VARCHAR(8)) AS request_dir_1,
(NULLIF(user_agent, '-')::VARCHAR(256)) AS user_agent,
(NULLIF(ssl_cipher, '-')::VARCHAR(64)) AS ssl_cipher ,
(NULLIF(ssl_protocol, '-')::VARCHAR(64)) AS ssl_protocol
FROM tmp_elb_access_log
WHERE request_time ~ '[2][0-9][0-9][0-9]-[0-1][0-9]-[0-3][0-9]'
)
;

処理概要

アクセス時刻、TIMESTAMP型に変換します
JSTでアクセス日時をもたせました。
配列カラム（port、request）は分割しました。
異常な時刻レコードは除外します。

アクセス解析例

backend_processing_timeの発生元ベスト10

SELECT
SPLIT_PART(user_agent,'/',1) as UA
,SUM(backend_processing_time)/60/60::int AS sum_backend_time
FROM elb_access_log
WHERE request_time > SYSDATE-90
and user_agent not like 'Mozilla%'
and user_agent not like 'Zabbix%'
and user_agent not like 'Amazon%'
and user_agent not like 'Incapsula%'
and user_agent not like 'Docomo%'
and user_agent not like 'SAMSUNG%'
and user_agent not like 'Opera%'
GROUP BY SPLIT_PART(user_agent,'/',1)
ORDER BY sum_backend_time desc
LIMIT 10

ヘルスチェック、通常ブラウザからのアクセスは除外しました。

順位	user_agent	処理時間(h)
1	Owlin bot v3 http:	91
2	OSlackbot 1.0 (+https:	75
3	OTwitterbot	31
4	OAnemone	26
5	Obrain (+http:	25
6	OScrapy	24
7	OFeedly	20
8	OHatena::UserAgent	18
9	OPlagger	17
10	ORuby	16

backend_processing_timeの発生先ベスト10

SELECT
request_uri
,(SUM(backend_processing_time)/60/60)::int AS sum_backend_time
FROM elb_access_log
WHERE request_time > SYSDATE-90
and request_dir_1 not in ('category','feed')
and request_uri != 'https://dev.classmethod.jp:80/'
GROUP BY request_uri
ORDER BY sum_backend_time desc
LIMIT 10

記事ページのみ対象としました

順位	表示ページ	投稿日	作者	処理時間(h)
1	非エンジニアに贈る「具体例でさらっと学ぶJSON」	2015年05月28日	都元ダイスケ	9
2	Windowsでシンボリックリンクを作る	2014年04月23日	梶原裕	9
3	[Excel] シートで非表示になっている名前の定義を消す方法	2013年05月01	諏訪悠紀	8
4	第1回はじめてのSpring framework	2013年03月07日	都元ダイスケ	8
5	iOS 9 で追加された App Transport Security の概要	2015年08月11日	平屋真吾	7
6	よく分かる！Android アプリのリリース手順のまとめアドカレ2013 : SP #20	2013年12月20日	諏訪悠紀	7
7	MacBook Airの動作が重くなったのでメンテナンスしたら軽くなった件	2015年04月20日	横田あかり	7
8	間違えて貼った収入印紙を返金してもらう方法	2014年12月05日	クニ吉	7
9	Vagrantって流行ってるらしいけど何が便利なの？	2013年07月31日	袴田	6
10	よく分かる！iOS アプリ開発に必要な証明書ファイルの作成方法アドカレ2013 : SP #4	2013年12月04日	おおはしりきたけ	6

考察

公開直後、参照が集中する記事についてはキャッシュ経由の配信となりますが、ロングテールで、一定の需要が存在する記事がキャッシュの乗りが悪く、サーバ負荷になっている事が伺えました。
上記レスポンスタイムは、GoogleAnalyticsなどでも確認が可能ですが、サーバのレスポンスコードなどを組み合わせた解析や、全量ログを前提とした抽出にはRedshiftは大きな効果を発揮すると考えられます。